RedisでTTLが不正なアイテムを探す

#AWS

#DevOps

小室啓

2019.12.09

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

こむろ＠札幌です。

寒い。 ^*1

まずはこちらをご覧ください

このグラフは ElastiCache（Redis）の BytesUsedForCache の3ヶ月にわたるメトリクスです。

波があるものの単調増加しているのが分かります。そしてある期間で急転直下しています。

細かい波は Expire による自動削除。後半の不規則な小さい波と巨大な急転直下が Eviction による強制的なアイテムの削除によるものと思われます。

背景

背景です。

Spring Boot 2.1.0.RELEASE
- Java ベースの Webアプリケーション（APIサーバー、一部UIを提供している）
- マスタデータのCacheやSession情報を Redis に格納している
- Redis 周りのライブラリは以下を利用
- spring-boot-starter-data-redis
- spring-session-data-redis
DynamoDB
- アプリケーションで利用するマスタデータはここに集約
- このデータの一部がCacheとして Redis に格納している
ElastiCache（Redis）
- Redis エンジンを（歴史的経緯から）シングルノードで稼働
- このシステム最大の SPOF （シングルノードのため）
- そして今回の問題の根幹（と思われていたもの）

本来Redisに格納されるデータは多かれ少なかれ Expire が指定されているはず。

特にCacheとして利用しているならばなおさらです（無限のCacheとは ? ）

現象

このアプリケーション、稼働から一定期間経過すると Evictionが発生し始めるという現象がありました。上記 BytesUsedForCache のグラフと同時期の Eviction のメトリクスは以下のとおりです。

Web アプリケーションがさばいているアクセス数もそれなりに多かったため（分間 1〜2万 Request程度）、当初は「 Expire するより前に新たに生成されたデータが溜まって一杯になっているのでは？」と考え、Requestの規模に応じて ElastiCache のノードインスタンスタイプを適宜変更していました。また Eviction のポリシーは allkeys-lru が設定されています。

しかしながら、インスタンスタイプを変更しても頻度は減るものの時間が経過すると Eviction が発生します。

初めは小さな Eviction が不定期で発生、最終的にほぼすべてのデータが Eviction 対象となり、空っぽになるという現象は依然として解決できていません。

諸悪の根源を突き止める

単調増加のグラフから単純に考えて、TTLが存在しない、もしくは TTLが異常に長い アイテムが存在するのではないかという疑念が前々からありました。そこで TTL を中心に確認してみます。

問題が発生している本番環境のデータがそのまま見れればよいのですが、いかんせん Redis なので全キー探索のようなコマンドを気軽に発行した瞬間にシステムダウンと言うことになりかねません。ステージング環境のノードで実行します。くれぐれも本番環境で実行しないようにしましょう・・・。

本番環境でやらかしちゃった人 Advent Calendar 2019

話題のアドベントカレンダーに参加する権利が手に入ってしまうかもしれません

TTL が設定されていない

yomon8 - RedisからTTL(Expire)設定されていないKeyの一覧を取得する

こちらのコマンドをそのまま利用させていただきました。ありがとうございます。

ElastiCache のノードはそのままでは外部からアクセスできないため、何らかのインスタンス等を経由する必要があります。今回はメンテナンス用のインスタンスが一台あったため、こちらを一時的に起動し、そこから redis-cli を使って接続します。

DBは一つしか利用していないため、0 番目を指定。

$ redis-cli -h REDIS_HOST
REDIS_HOST:6379> select 0
OK

INFO コマンドを打ってみます。

REDIS_HOST:6379> INFO keyspace
# Keyspace
db0:keys=1855,expires=1484,avg_ttl=174665

keys が1855に対し、 expires が1484。これはもしかして TTL が設定されていないのが 300件強あるということなのでは・・・？

今回はLuaではなくCLIで行うコマンドを実行しました。

REDIS_HOST:6379> eval "local t = {} local i = 1 for _,v in ipairs(redis.call('KEYS', '*')) do if redis.call('TTL',v) == -1 then t[i] = v i = i + 1 end end return t" 0
  1) "ElastiCacheMasterReplicationTimestamp"
  2) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXA=="
  3) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXB=="
  4) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXC=="
  5) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXD=="

 ......

 370) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXY=="
 371) "spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXZ=="

大量に出てきました。SpringSession、お前だったのか。ずっと生きていたのは。

トータルで371件。 1855 - 1484 = 371 なので合致しそう。

TTL が本当に指定されていないのかを確認します。任意の1つのキーの TTL を調べます。

TTLを確認

REDIS_HOST:6379> TTL spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXZ==
(integer) -1

-1 なので TTL が設定されていないか、そもそもアイテムが存在しない。

アイテムが存在するかを確認します。

Typeを確認

REDIS_HOST:6379> TYPE spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXZ==
set

Setなので SET 系のコマンドが有効。

redis 2.0.3 documentation - command refference

Setの取得

REDIS_HOST:6379> SMEMBERS spring:session:index:org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME:XXXXXXXXXXXXXXXXXXXZ==
1) "\"f55158a8-46d5-4f2a-b7cf-XXXXXXXXXX\""

アイテムは存在するようです。

つまり TTL が設定されていない、が確定で良さそう。

TTLが異常に長い

次に異常に長い場合も確認します。この場合グラフを見ると概ね一ヶ月を超えたあたりから Eviction が検出されているので 1ヶ月（31日）以上の TTL が設定されていたら長いとして計測します。

31日 = 2678400 秒

先程のコマンドを少し修正します。

REDIS_HOST:6379> eval "local t = {} local i = 1 for _,v in ipairs(redis.call('KEYS', '*')) do if redis.call('TTL',v) >= 2678400 then t[i] = v i = i + 1 end end return t" 0

実行結果は以下。

REDIS_HOST:6379> eval "local t = {} local i = 1 for _,v in ipairs(redis.call('KEYS', '*')) do if redis.call('TTL',v) >= 2678400 then t[i] = v i = i + 1 end end return t" 0
(empty list or set)

31日以上の TTL が設定されてるアイテムはなさそう。

さらに試しに 1日の TTL で確認。

REDIS_HOST:6379> eval "local t = {} local i = 1 for _,v in ipairs(redis.call('KEYS', '*')) do if redis.call('TTL',v) >= 86400 then t[i] = v i = i + 1 end end return t" 0
(empty list or set)

こちらもなさそう。

TTL が異常に長いアイテムはないということで良さそうです。

結論

線形増加の元になっているのは TTL が設定されていないアイテムが原因で間違いなさそうです。 Eviction の山の推移については以下の状況ではないかと推測しています。

TTL が設定されていないアイテムがあるため徐々に底上げ
メモリ使用量が満杯になった段階で、Eviction が発生。この際は TTL が設定されていて古いものから削除されていく (Eviction の小さな山)
いよいよ TTL が設定されたものがなくなり、削除できるものがなくなってくる
Eviction が設定されていないすべてのアイテムが強制的にパージされる (大量の Eviction 。削除処理以外すべてが停止する)

他環境より格段にハードに使われている環境だったため、

塵が本当に山になってしまった、
さらに数年に渡りアクセス数が伸び続けていることから山の成長速度が加速した
- 稼働当初と比べると分間アクセスが2倍以上

ことから頻繁に顕在化するに至ったのではないかと思います。上記現象を開発チームへデータと共に報告し、すでに修正に着手しています。

まとめ

セッション情報が積算されるとはいえ、一つ一つのデータサイズが小さく「塵も積もれば山となる」レベルの緩やかな増加であったため、かなりハードに使われないと気づかなかった事象です。今後はこういった Cache への TTL が正常に設定されているかなどの確認もしないといけません。（自動テストでやるかどうかはさておき）

実際起きている事象のデータを観察することで見えることはとても多く明確なエビデンスとしてサンプルデータを提出できるはずです。開発チームにコードで追ってもらうより早く確実な情報と現象の解明ができるはず。

Dev, Ops（もしくはアプリとインフラ）を分断して考えるのではなく、双方が協力する、もしくは双方の知識を持ちそれぞれを橋渡しできる人が必要です。 ^*2